Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add execution start and end time metadata for code cells #29

Open
wants to merge 11 commits into
base: main
Choose a base branch
from

Conversation

Darshan808
Copy link

References #22

  • Added execution start and end times to code cell metadata, visible when timing recording is enabled by user.
  • Computed on the server side to ensure persistence even after the notebook is closed.

Screenshots

image

Copy link

github-actions bot commented Jan 7, 2025

Binder 👈 Launch a Binder on branch Darshan808/jupyter-server-nbmodel/add-execution-timing-metadata

@krassowski krassowski added the enhancement New feature or request label Jan 7, 2025
Copy link
Collaborator

@krassowski krassowski left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🚀 I think we would want to add a test, for example see:

async def test_post_execute(jp_fetch, pending_kernel_is_ready, snippet, output):

since the exact timestamp will vary I would just check that the timing metadata is present and that the end time is greater than start time.


if metadata["record_timing"]:
time_info = ycell["metadata"].get("execution",{})
time_info["start_time"] = datetime.now(timezone.utc).isoformat()[:-6]
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For the metadata I think we will want to match the exact identifiers as used on the frontend, so instead of start_time we would use shell.execute_reply.started and for end time - shell.execute_reply - although these are less readable, it would make jupyter-server-nbmodel a drop-in replacement and compatible with existing extensions like jupyterlab-execute-time.

There also should be execution_failed for when the execution fails.

@Darshan808
Copy link
Author

I think we would want to add a test, for example see:

For testing whether the metadata is being added correctly, we would need to pass ydoc: The YDoc jupyter server extension and metadata: Execution context. But during testing, we pass None and {} as their values due to which we get response from server but cell metadata is not added.

Can we somehow create dummy ydoc and metadata and pass it instead or do we have some other better way to do this?

@krassowski
Copy link
Collaborator

krassowski commented Jan 8, 2025

Can we somehow create dummy ydoc and metadata and pass it instead or do we have some other better way to do this?

You can change config to something like:

"ServerApp": {
    "jpserver_extensions": {
        "jupyter_server_ydoc": True,
        "jupyter_server_nbmodel": True,
        "jupyter_server_fileid": True,  # from jupyter_server_ydoc
    },
    "token": "",  # not sure if needed
    "disable_check_xsrf": True,   # not sure if needed
},

in

pytest_plugins = ("pytest_jupyter.jupyter_server",)
@pytest.fixture
def jp_server_config(jp_server_config):
return {
"ServerApp": {
"jpserver_extensions": {"jupyter_server_nbmodel": True, "jupyter_server_ydoc": False}
}
}

to enable jupyter_server_ydocand then I think you can access it from jp_serverapp.web_app.settings["jupyter_server_ydoc"] as in here, or using self.serverapp.extension_manager.extension_apps as in

RTC_EXTENSIONAPP_NAME = "jupyter_server_ydoc"
STOP_TIMEOUT = 3
_request_id_regex = r"(?P<request_id>\w+-\w+-\w+-\w+-\w+)"
class Extension(ExtensionApp):
name = "jupyter_server_nbmodel"
def initialize_handlers(self):
rtc_extension = None
rtc_extensions = self.serverapp.extension_manager.extension_apps.get(
RTC_EXTENSIONAPP_NAME, set()
)

You may also need to create a real collaborative notebook, for that purpose add jupyter_server_ydoc.pytest_plugin which will pull fixtures from https://github.com/jupyterlab/jupyter-collaboration/blob/main/projects/jupyter-server-ydoc/jupyter_server_ydoc/pytest_plugin.py and allow you to use rtc_create_notebook.

metadata: Execution context

Is this the same as we are sending from frontend? If so you should be able to populate it with cell_id, document_id and "record_timing": True.

@Darshan808 Darshan808 requested a review from krassowski January 9, 2025 10:49
conftest.py Outdated Show resolved Hide resolved
conftest.py Outdated Show resolved Hide resolved
pyproject.toml Outdated Show resolved Hide resolved
@Darshan808
Copy link
Author

This CI error seems similar to the one described in the jupyterlab/jupyter-collaboration#252.

@krassowski
Copy link
Collaborator

I think these are warnings, so I would not be too worried. I would focus on fixing

ERROR jupyter_server_nbmodel/tests/test_handlers.py::test_execution_timing_metadata - KeyError: 'file_id_manager'

@Darshan808
Copy link
Author

I've spent considerable time and tried various methods to resolve the issue, but I still encounter an error stating "KeyError: 'event_logger'" in traitlets.
Screenshot from 2025-01-10 08-13-26

@krassowski
Copy link
Collaborator

It looks like the real problem is the timeout (you can see it if you scroll up):

________________________ test_execution_timing_metadata ________________________

jp_fetch = <function jp_fetch.<locals>.client_fetch at 0x7f20b5315bc0>
pending_kernel_is_ready = <function pending_kernel_is_ready.<locals>._ at 0x7f20b5315c60>
rtc_create_notebook = <function rtc_create_notebook.<locals>._inner at 0x7f20b5315ee0>
jp_serverapp = <jupyter_server.serverapp.ServerApp object at 0x7f20b5354fb0>

    @pytest.mark.timeout(TEST_TIMEOUT)
    async def test_execution_timing_metadata(jp_fetch, pending_kernel_is_ready, rtc_create_notebook, jp_serverapp):
        snippet = "a = 1"
        nb = nbformat.v4.new_notebook(
            cells=[nbformat.v4.new_code_cell(source=snippet, execution_count=1)]
        )
        nb_content = nbformat.writes(nb, version=4)
        path, _ = await rtc_create_notebook("test.ipynb", nb_content, store=True)
        collaboration = jp_serverapp.web_app.settings["jupyter_server_ydoc"]
        fim = jp_serverapp.web_app.settings["file_id_manager"]
        document = await collaboration.get_document(
            path=path, content_type="notebook", file_format="json", copy=False
        )
        doc = document.get()
        document_id = f'json:notebook:{fim.get_id("test.ipynb")}'
        cell_id = doc["cells"][0].get("id")
    
        r = await jp_fetch(
            "api", "kernels", method="POST", body=json.dumps({"name": NATIVE_KERNEL_NAME})
        )
        kernel = json.loads(r.body.decode())
        await pending_kernel_is_ready(kernel["id"])
    
>       response = await wait_for_request(
            jp_fetch,
            "api",
            "kernels",
            kernel["id"],
            "execute",
            method="POST",
            body=json.dumps({"code": snippet, "metadata":{"cell_id":cell_id,"document_id":document_id,"record_timing":True}}),
        )

jupyter_server_nbmodel/tests/test_handlers.py:175: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
jupyter_server_nbmodel/tests/test_handlers.py:41: in wait_for_request
    ans = await _wait_request(fetch, location)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

fetch = <function jp_fetch.<locals>.client_fetch at 0x7f20b5315bc0>
endpoint = '/api/kernels/c056[265](https://github.com/datalayer/jupyter-server-nbmodel/actions/runs/12688982252/job/35366715215?pr=29#step:7:266)5-7fb9-47f9-b827-161f37a61348/requests/7d2a5526-733f-478c-b057-b28e9f5c9952'

    async def _wait_request(fetch, endpoint: str):
        """Poll periodically to fetch the execution request result."""
        start_time = datetime.datetime.now()
        elapsed = 0.0
        while elapsed < 0.9 * TEST_TIMEOUT:
            await asyncio.sleep(SLEEP)
            response = await fetch(endpoint, raise_error=False)
            if response.code >= 400:
                response.rethrow()
            if response.code != 202:
                return response
    
            elapsed = (datetime.datetime.now() - start_time).total_seconds()
    
>       raise TimeoutError(f"Request {endpoint} timed out ({elapsed}s).")
E       TimeoutError: Request /api/kernels/c0562655-7fb9-47f9-b827-161f37a61348/requests/7d2a5526-733f-478c-b057-b28e9f5c9952 timed out (13.696742s).

jupyter_server_nbmodel/tests/test_handlers.py:31: TimeoutError

During handling of the above exception, another exception occurred:

>       lambda: ihook(item=item, **kwds), when=when, reraise=reraise
    )
E   pytest.PytestUnraisableExceptionWarning: Exception ignored in: <function MemoryObjectSendStream.__del__ at 0x7f20b96428e0>
E   
E   Traceback (most recent call last):
E     File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/traitlets/traitlets.py", line 632, in get
E       value = obj._trait_values[self.name]
E               ~~~~~~~~~~~~~~~~~^^^^^^^^^^^
E   KeyError: 'event_logger'
E   
E   During handling of the above exception, another exception occurred:
E   
E   Traceback (most recent call last):
E     File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/anyio/streams/memory.py", line 313, in __del__
E       warnings.warn(
E   ResourceWarning: Unclosed <MemoryObjectSendStream at 7f20b509e9f0>

It seems that it is stalling in the with ycell.doc.transaction(): context manager. I think I know what might be going on, will push a fix.

@krassowski
Copy link
Collaborator

It looks like test_post_input_execute causes other tests to fail randomly no matter what.

The tests are also failing on the main branch so this is not introduced by this PR. Below is an example where test_post_erroneous_execute fails. If I comment out test_post_input_execute then it passes:

=========================== short test summary info ============================
FAILED jupyter_server_nbmodel/tests/test_handlers.py::test_post_erroneous_execute[1 / 0-{"output_type": "error", "ename": "ZeroDivisionError", "evalue": "division by zero", "traceback": ["\\u001b[0;31m---------------------------------------------------------------------------\\u001b[0m", "\\u001b[0;31mZeroDivisionError\\u001b[0m                         Traceback (most recent call last)", "Cell \\u001b[0;32mIn[1], line 1\\u001b[0m\\n\\u001b[0;32m----> 1\\u001b[0m \\u001b[38;5;241;43m1\\u001b[39;49m\\u001b[43m \\u001b[49m\\u001b[38;5;241;43m/\\u001b[39;49m\\u001b[43m \\u001b[49m\\u001b[38;5;241;43m0\\u001b[39;49m\\n", "\\u001b[0;31mZeroDivisionError\\u001b[0m: division by zero"]}] - pytest.PytestUnraisableExceptionWarning: Exception ignored in: <function Socket.__del__ at 0x7f063fc5be20>
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/traitlets/traitlets.py", line 632, in get
    value = obj._trait_values[self.name]
            ~~~~~~~~~~~~~~~~~^^^^^^^^^^^
KeyError: 'event_logger'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/zmq/sugar/socket.py", line 179, in __del__
    warn(
ResourceWarning: Unclosed socket <zmq.asyncio.Socket(zmq.DEALER) at 0x7f063cc9ee40>
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_execute[print('hello buddy')-{"output_type": "stream", "name": "stdout", "text": "hello buddy\\n"}]
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_execute[a = 1-]
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_execute[from IPython.display import HTML\nHTML('<p><b>Jupyter</b> rocks.</p>')-{"output_type": "execute_result", "metadata": {}, "data": {"text/plain": "<IPython.core.display.HTML object>", "text/html": "<p><b>Jupyter</b> rocks.</p>"}, "execution_count": 1}]
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_input_execute
=================== 1 failed, 4 passed, 1 warning in 14.57s ====================
Deleting active ExecutionStack. Be sure to call `await ExecutionStack.dispose()`.
/home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py:340: RuntimeWarning: coroutine 'ExecutionStack.dispose' was never awaited
  self.dispose()
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
Could not destroy zmq context for <jupyter_client.asynchronous.client.AsyncKernelClient object at 0x7f063efd5df0>
Task was destroyed but it is pending!
task: <Task pending name='Task-124' coro=<_kernel_worker() running at /home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py:272> wait_for=<Future pending cb=[Task.task_wakeup()]>>
Exception ignored in: <coroutine object _kernel_worker at 0x7f063ceb5fe0>
Traceback (most recent call last):
  File "/home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py", line 301, in _kernel_worker
    raise to_raise
  File "/home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py", line 272, in _kernel_worker
    uid, snippet, metadata = await queue.get()
                             ^^^^^^^^^^^^^^^^^
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/asyncio/queues.py", line 160, in get
    getter.cancel()  # Just in case getter is not done yet.
    ^^^^^^^^^^^^^^^
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/asyncio/base_events.py", line 794, in call_soon
    self._check_closed()
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/asyncio/base_events.py", line 540, in _check_closed

@krassowski
Copy link
Collaborator

It looks like the relation is with number of tests and the teardown sequence. It seems that the kernel workers are not being properly terminated, but even adding manual call to stop_extension() at the end of each test does not help. This is looking quite tricky to solve, but probably best to solve it in another PR first.

@krassowski
Copy link
Collaborator

It seems that this is tracked in #16. Indeed running tests individually works.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants